RDS Proxyが拡張クエリプロトコルに対応し、ピン留めの発生条件が緩和されました
CX事業部@大阪の岩田です。
本日のアップデートによりRDS ProxyがPostgreSQLの拡張クエリプロトコルをサポートするようになりました。本ブログではこのアップデートについてご紹介します。
ちなみに以前はpinningが「ピン留め」と翻訳されていましたが、最近は「固定」翻訳とされているようです。個人的にはピン留めの方がしっくりくるので、本ブログにおいては公式日本語ドキュメントが「固定」と翻訳している事象を全て「ピン留め」と呼ぶことにします。
そもそも拡張クエリプロトコルとは？
PostgreSQLではクエリを実行するためのプロトコルに、簡易クエリプロトコルと拡張クエリプロトコルという2つのプロトコルが存在します。ざっくりとした理解として、簡易クエリプロトコルの場合は生のSQL文をそのままサーバーに送信するのに対して、拡張クエリプロトコルの場合はパラメータを利用したSQL文を送信した後、パラメータにバインドする値を送信してクエリを実行すると考えておくと良いでしょう。
例えば現在のDBユーザーがpostgresかチェックするクエリを実行する場合の流れは以下のようなイメージになります。
- 簡易クエリプロトコルの場合
select user = 'postgres'というSQL文を送信して実行
- 拡張クエリプロトコルの場合
select user = $1というSQL文に加え、$1というパラメータに'postgres'をバインドするという情報を送信して実行
もう少し詳細について知りたい場合は以下のページなど見て頂くと理解しやすいです。
拡張クエリプロトコルを使うとPREPARED STATEMENTと同様にSQLインジェクションのリスクヘッジや、SQL文のパース結果再利用によるパフォーマンス向上などが期待できるため、PostgreSQL向けの各種DBドライバやライブラリは拡張クエリプロトコルを利用しているケースが多いです。
何がうれしいのか？
前述のように拡張クエリプロトコルにはセキュリティやパフォーマンスの面でメリットがあるのですが、RDS Proxyに対して拡張クエリプロトコルを利用してしまうと、当該DBセッションがピン留めされてしまい複数のクライアント間でDBとの物理接続を共有できなくなるという課題がありました。
ピン留めが発生するとRDS Proxyを利用するメリットが薄れてしまうため、拡張クエリプロトコルを利用しないようにしたいところではあるのですが、そうなると今度はセキュリティやパフォーマンスのメリットが犠牲になってしまいます。また、アプリケーション側の実装が煩雑になるというデメリットもあります。アプリケーションの開発にORMを利用するケースは多いと思いますが、拡張クエリプロトコルの利用を回避しようとするとORMの便利な処理がそのまま利用できなくなり、生SQLを書くに近い低レベルな実装が必要になることが多く、開発生産性に悪影響を及ぼします。
例えばですが、以前私がお手伝いしたプロジェクトではTypeORMを利用して以下のようなコードが書かれていました
const pet = connection.getRepository(Pet).findOne(PetId)
このコードを実行するとピン留めが発生してしまうので、コードを以下のように修正して対応しました。
const pet = connection.getRepository(Pet).findOne({
where: `pet_id = ‘${PetId}’`
})
この実装ではPetIdという変数の中身がバリデーション済みで適切にサニタイズされていることが必須となります。この程度であれば問題なく対応できますが、カラム数の多いテーブルへのINSERT文を適切に組み立てることを考えると、ちょっとやりたくないですよね。結局そのプロジェクトでは簡単なSELECT/DELETE文のみピン留め対策を行い、INSERT/UPDATE文についてはピン留めを許容する方針としました。
拡張クエリプロトコル利用による諸々の恩恵を受けつつも、ピン留めを回避できるようになったというのが今回のアップデートの大きなメリットです。
やってみる
RDS Proxyの「拡張されたログ記録」を有効にした状態で実際に拡張クエリプロトコルがピン留め対象にならないことを確認してみましょう。
環境
以後の検証に利用した環境です。
- RDS for PostgreSQL: 15.3-R2
- デフォルトから以下のパラメータを変更
- log_statement: all
- rds.force_ssl: 0
- Node.js: v18.18.2
- pg: 8.11.3
Preprare Statementを利用してピン留めが発生することを確認
まずは普通にPreprare Statementを利用してピン留めが発生することを確認してみます。
psqlを使ってRDS Proxy経由でRDSに接続し、Preprare Statementを実行してみます。なおpsqlからのクエリ発行は簡易クエリプロトコルになります。
postgres=> prepare test as select user = $1;
PREPARE
postgres=> execute test('postgres');
?column?
----------
t
(1 row)
RDS Proxyのログを確認するとピン留めが発生したことが分かります。
2023-11-11T03:04:26.822Z [WARN] [proxyEndpoint=default] [clientConnection=489382254] The client session was pinned to the database connection [dbConnection=4017617057] for the remainder of the session. The proxy can't reuse this connection until the session ends. Reason: SQL changed session settings that the proxy doesn't track. Consider moving session configuration to the proxy's initialization query. Digest: "prepare test as select user = $1;".
拡張クエリプロトコルでnameを指定せずにクエリを実行してみる
以下のコードを使って、検証用のEC2からRDS Proxyに接続してクエリを発行してみます。
const pg = require('pg')
async function main(){
const client = new pg.Client({
host: '<RDS Proxyのエンドポイント>',
database: 'postgres',
user: 'postgres',
password: '<パスワード>',
})
await client.connect()
await client.query('SELECT user = $1', ['postgres'])
await client.end()
}
main()
コードを実行した際のRDS側のログです。拡張クエリプロトコルによるunnamedなクエリが実行されていることが分かります。
2023-11-11 03:36:22 UTC:172.31.17.134(12099):postgres@postgres:[4548]:LOG: duration: 0.052 ms parse <unnamed>: DEALLOCATE ALL 2023-11-11 03:36:22 UTC:172.31.17.134(12099):postgres@postgres:[4548]:LOG: duration: 0.008 ms bind <unnamed>: DEALLOCATE ALL 2023-11-11 03:36:22 UTC:172.31.17.134(12099):postgres@postgres:[4548]:LOG: execute <unnamed>: DEALLOCATE ALL 2023-11-11 03:36:22 UTC:172.31.17.134(12099):postgres@postgres:[4548]:LOG: duration: 0.015 ms 2023-11-11 03:36:22 UTC:172.31.17.134(12099):postgres@postgres:[4548]:LOG: duration: 0.045 ms parse <unnamed>: SELECT user = $1 2023-11-11 03:36:22 UTC:172.31.17.134(12099):postgres@postgres:[4548]:LOG: duration: 0.040 ms bind <unnamed>: SELECT user = $1 2023-11-11 03:36:22 UTC:172.31.17.134(12099):postgres@postgres:[4548]:DETAIL: parameters: $1 = 'postgres' 2023-11-11 03:36:22 UTC:172.31.17.134(12099):postgres@postgres:[4548]:LOG: execute <unnamed>: SELECT user = $1 2023-11-11 03:36:22 UTC:172.31.17.134(12099):postgres@postgres:[4548]:DETAIL: parameters: $1 = 'postgres'
RDS Proxyのログです。ピン留めは発生していないことが分かります。やったぜ！
2023-11-11T03:36:22.316Z [INFO] [proxyEndpoint=default] [clientConnection=2051681955] A new client connected from 172.31.40.157:54478. 2023-11-11T03:36:22.316Z [DEBUG] [proxyEndpoint=default] [clientConnection=2051681955] Received Startup Message: [username="postgres", database="postgres", protocolMajorVersion=3, protocolMinorVersion=0, sslEnabled=false] 2023-11-11T03:36:22.349Z [DEBUG] [proxyEndpoint=default] [clientConnection=2051681955] Proxy authentication with PostgreSQL native password authentication succeeded for user "postgres" with TLS off. 2023-11-11T03:36:22.355Z [DEBUG] [proxyEndpoint=default] [clientConnection=2051681955] The client connection borrowed the database connection [dbConnection=610606420] for the next query/transaction. 2023-11-11T03:36:22.363Z [DEBUG] [proxyEndpoint=default] [clientConnection=2051681955] The database connection [dbConnection=610606420] borrowed from the connection pool is being released to the connection pool. 2023-11-11T03:36:22.367Z [INFO] [proxyEndpoint=default] [clientConnection=2051681955] The client connection closed. Reason: The client requested that the connection close.
拡張クエリプロトコルでnameを指定してクエリを実行してみる
先程はunnamedなPREPARED STATEMENTで試したので、今度は名前付きのクエリで試してみます。以下のようにコードを修正して再度実行してみます。
const pg = require('pg')
async function main(){
const client = new pg.Client({
host: '<RDS Proxyのエンドポイント>',
database: 'postgres',
user: 'postgres',
password: '<パスワード>',
})
await client.connect()
await client.query({
name: 'test',
text: 'SELECT user = $1',
values: ['postgres']
})
await client.end()
}
main()
RDSのログは以下です。
2023-11-11 03:43:37 UTC:172.31.17.134(12099):postgres@postgres:[4548]:LOG: duration: 0.025 ms parse <unnamed>: DEALLOCATE ALL 2023-11-11 03:43:37 UTC:172.31.17.134(12099):postgres@postgres:[4548]:LOG: duration: 0.008 ms bind <unnamed>: DEALLOCATE ALL 2023-11-11 03:43:37 UTC:172.31.17.134(12099):postgres@postgres:[4548]:LOG: execute <unnamed>: DEALLOCATE ALL 2023-11-11 03:43:37 UTC:172.31.17.134(12099):postgres@postgres:[4548]:LOG: duration: 0.015 ms 2023-11-11 03:43:37 UTC:172.31.17.134(12099):postgres@postgres:[4548]:LOG: duration: 0.064 ms parse test: SELECT user = $1 2023-11-11 03:43:37 UTC:172.31.17.134(12099):postgres@postgres:[4548]:LOG: duration: 0.041 ms bind test: SELECT user = $1 2023-11-11 03:43:37 UTC:172.31.17.134(12099):postgres@postgres:[4548]:DETAIL: parameters: $1 = 'postgres' 2023-11-11 03:43:37 UTC:172.31.17.134(12099):postgres@postgres:[4548]:LOG: execute test: SELECT user = $1 2023-11-11 03:43:37 UTC:172.31.17.134(12099):postgres@postgres:[4548]:DETAIL: parameters: $1 = 'postgres' 2023-11-11 03:43:37 UTC:172.31.17.134(12099):postgres@postgres:[4548]:LOG: duration: 0.022 ms
RDS Proxyのログは以下の通りです。ピン留めが発生するかなと予想していたのですが、ピン留めは発生しませんでした！
2023-11-11T03:43:37.414Z [INFO] [proxyEndpoint=default] [clientConnection=2880091403] A new client connected from 172.31.40.157:36464. 2023-11-11T03:43:37.415Z [DEBUG] [proxyEndpoint=default] [clientConnection=2880091403] Received Startup Message: [username="postgres", database="postgres", protocolMajorVersion=3, protocolMinorVersion=0, sslEnabled=false] 2023-11-11T03:43:37.442Z [DEBUG] [proxyEndpoint=default] [clientConnection=2880091403] Proxy authentication with PostgreSQL native password authentication succeeded for user "postgres" with TLS off. 2023-11-11T03:43:37.447Z [DEBUG] [proxyEndpoint=default] [clientConnection=2880091403] The client connection borrowed the database connection [dbConnection=610606420] for the next query/transaction. 2023-11-11T03:43:37.450Z [DEBUG] [proxyEndpoint=default] [clientConnection=2880091403] The database connection [dbConnection=610606420] borrowed from the connection pool is being released to the connection pool. 2023-11-11T03:43:37.454Z [INFO] [proxyEndpoint=default] [clientConnection=2880091403] The client connection closed. Reason: The client requested that the connection close.
一応パケットキャプチャで意図通りのメッセージが送信できているか確認してみましたが、意図通り拡張クエリプロトコルで「test」というnameを指定してBindのメッセージを送信していることが確認できました。
nameを指定したクエリ実行について深掘りしてみる
nameを指定した場合もピン留めが発生しなかったため、RDS Proxyにコネクションが返却されるタイミングについてもう少し詳しく確認してみます。先程のクエリ発行部分を以下のように修正します。これでtestという名前のクエリ実行後に10秒待機を2回繰り返すことになります。
await client.query({
name: 'test',
text: 'SELECT user = $1',
values: ['postgres']
})
await new Promise(resolve => setTimeout(resolve, 10000))
await client.query({
name: 'test',
text: 'SELECT user = $1',
values: ['postgres']
})
await new Promise(resolve => setTimeout(resolve, 10000))
今回はRDS Proxyのログを先に確認してみます。
2023-11-11T04:18:12.332Z [INFO] [proxyEndpoint=default] [clientConnection=2034744493] A new client connected from 172.31.40.157:38286. 2023-11-11T04:18:12.332Z [DEBUG] [proxyEndpoint=default] [clientConnection=2034744493] Received Startup Message: [username="postgres", database="postgres", protocolMajorVersion=3, protocolMinorVersion=0, sslEnabled=false] 2023-11-11T04:18:12.361Z [DEBUG] [proxyEndpoint=default] [clientConnection=2034744493] Proxy authentication with PostgreSQL native password authentication succeeded for user "postgres" with TLS off. 2023-11-11T04:18:12.368Z [DEBUG] [proxyEndpoint=default] [clientConnection=2034744493] The client connection borrowed the database connection [dbConnection=610606420] for the next query/transaction. 2023-11-11T04:18:12.372Z [DEBUG] [proxyEndpoint=default] [clientConnection=2034744493] The database connection [dbConnection=610606420] borrowed from the connection pool is being released to the connection pool. 2023-11-11T04:18:22.380Z [DEBUG] [proxyEndpoint=default] [clientConnection=2034744493] The client connection borrowed the database connection [dbConnection=610606420] for the next query/transaction. 2023-11-11T04:18:22.382Z [DEBUG] [proxyEndpoint=default] [clientConnection=2034744493] The database connection [dbConnection=610606420] borrowed from the connection pool is being released to the connection pool. 2023-11-11T04:18:32.396Z [INFO] [proxyEndpoint=default] [clientConnection=2034744493] The client connection closed. Reason: The client requested that the connection close.
検証用コードの方では1回目のクエリ実行〜2回目のクエリ実行までの間に10秒の待機を挟みましたが、The client connection borrowed the database connection [dbConnection=...] for the next query/transaction.のログとThe database connection [dbConnection=...] borrowed from the connection pool is being released to the connection pool.のログまでの間にほぼタイムラグがありません。nameを指定したクエリであっても、クエリ実行完了後に即RDS Proxyにコネクションを返却していることが分かります。
ここで気になるのが、複数のクライアントをまたいでname:testのクエリが共有されることにならないのか？という点です。クライアント側としては接続先がRDSなのかRDS Proxyなのか？他のクライアントと接続が共有されていないのか？といったことは意識しないため、自身が新たに実行しようとしているname:testのクエリが実はサーバー側では既に別の定義で存在するといったことが起こりえるはずです。こういった問題を回避するための防御壁としてピン留めという事象が存在するはずなのですが、今回のアップデートによって拡張クエリプロトコルを利用した場合でもピン留めが発生しないようになりました。本当に大丈夫なのでしょうか？
改めて先程までのRDSのログを良く分析してみると、parse testの前に以下の様なログが出力されており、DEALLOCATE ALL が実行されていることが分かります。
2023-11-11 03:43:37 UTC:172.31.17.134(12099):postgres@postgres:[4548]:LOG: duration: 0.025 ms parse <unnamed>: DEALLOCATE ALL 2023-11-11 03:43:37 UTC:172.31.17.134(12099):postgres@postgres:[4548]:LOG: duration: 0.008 ms bind <unnamed>: DEALLOCATE ALL 2023-11-11 03:43:37 UTC:172.31.17.134(12099):postgres@postgres:[4548]:LOG: execute <unnamed>: DEALLOCATE ALL 2023-11-11 03:43:37 UTC:172.31.17.134(12099):postgres@postgres:[4548]:LOG: duration: 0.015 ms 2023-11-11 03:43:37 UTC:172.31.17.134(12099):postgres@postgres:[4548]:LOG: duration: 0.064 ms parse test:
このことから考えると、RDS Proxyは拡張クエリプロトコルのメッセージをRDSにプロキシする際、DEALLOCATE ALLを自動で挿入していると推測できます。自動でDEALLOCATE ALLが発行されるのであれば、nameが指定されたクエリも毎回破棄されるため、複数のクライアント間で同じnameのクエリが共有されるようなことにはなりません。RDS ProxyがDEALLOCATE ALLを差し込むことで、全てのクエリが擬似的にunnamedなクエリとして実行されていると考えると辻褄が合いそうです。
少し横道に逸れてしまいましたが、改めてこの検証パターンでのRDSのログを確認しておきましょう。ログは以下のようになりました。
2023-11-11 04:18:12 UTC:172.31.17.134(12099):postgres@postgres:[4548]:LOG: duration: 0.031 ms parse <unnamed>: DEALLOCATE ALL 2023-11-11 04:18:12 UTC:172.31.17.134(12099):postgres@postgres:[4548]:LOG: duration: 0.007 ms bind <unnamed>: DEALLOCATE ALL 2023-11-11 04:18:12 UTC:172.31.17.134(12099):postgres@postgres:[4548]:LOG: execute <unnamed>: DEALLOCATE ALL 2023-11-11 04:18:12 UTC:172.31.17.134(12099):postgres@postgres:[4548]:LOG: duration: 0.017 ms 2023-11-11 04:18:12 UTC:172.31.17.134(12099):postgres@postgres:[4548]:LOG: duration: 0.060 ms parse test: SELECT user = $1 2023-11-11 04:18:12 UTC:172.31.17.134(12099):postgres@postgres:[4548]:LOG: duration: 0.042 ms bind test: SELECT user = $1 2023-11-11 04:18:12 UTC:172.31.17.134(12099):postgres@postgres:[4548]:DETAIL: parameters: $1 = 'postgres' 2023-11-11 04:18:12 UTC:172.31.17.134(12099):postgres@postgres:[4548]:LOG: execute test: SELECT user = $1 2023-11-11 04:18:12 UTC:172.31.17.134(12099):postgres@postgres:[4548]:DETAIL: parameters: $1 = 'postgres' 2023-11-11 04:18:12 UTC:172.31.17.134(12099):postgres@postgres:[4548]:LOG: duration: 0.036 ms ...略 2023-11-11 04:18:22 UTC:172.31.17.134(12099):postgres@postgres:[4548]:LOG: duration: 0.024 ms parse <unnamed>: DEALLOCATE ALL 2023-11-11 04:18:22 UTC:172.31.17.134(12099):postgres@postgres:[4548]:LOG: duration: 0.009 ms bind <unnamed>: DEALLOCATE ALL 2023-11-11 04:18:22 UTC:172.31.17.134(12099):postgres@postgres:[4548]:LOG: execute <unnamed>: DEALLOCATE ALL 2023-11-11 04:18:22 UTC:172.31.17.134(12099):postgres@postgres:[4548]:LOG: duration: 0.019 ms 2023-11-11 04:18:22 UTC:172.31.17.134(12099):postgres@postgres:[4548]:LOG: duration: 0.066 ms parse test: SELECT user = $1 2023-11-11 04:18:22 UTC:172.31.17.134(12099):postgres@postgres:[4548]:LOG: duration: 0.041 ms bind test: SELECT user = $1 2023-11-11 04:18:22 UTC:172.31.17.134(12099):postgres@postgres:[4548]:DETAIL: parameters: $1 = 'postgres' 2023-11-11 04:18:22 UTC:172.31.17.134(12099):postgres@postgres:[4548]:LOG: execute test: SELECT user = $1 2023-11-11 04:18:22 UTC:172.31.17.134(12099):postgres@postgres:[4548]:DETAIL: parameters: $1 = 'postgres' 2023-11-11 04:18:22 UTC:172.31.17.134(12099):postgres@postgres:[4548]:LOG: duration: 0.021 ms
注目したいのが、parse test:が2回出力されていることです。nameを指定しているので、2回目はbindから始まるのが期待値のはずです。実際にクライアント側でパケットキャプチャした結果を見るとparseのメッセージは初回のクエリ実行時のみ送信されています。
クライアントからは1回しかparseのメッセージを送信していないのに、なぜRDSのログにはparseのログが2回出力されているのでしょうか？先程の検証用プログラムを修正し、RDS Proxyを経由せずに直接RDSにクエリを発行するようにします。
const client = new pg.Client({
host: '<ここをRDSのエンドポイントに変更>',
database: 'postgres',
user: 'postgres',
password: '<パスワード>',
})
この状態で再度検証用のプログラムを再度実行。RDSのログを確認してみましょう。
2023-11-11 05:16:41 UTC:172.31.40.157(42220):postgres@postgres:[8420]:LOG: duration: 0.225 ms parse test: SELECT user = $1 2023-11-11 05:16:41 UTC:172.31.40.157(42220):postgres@postgres:[8420]:LOG: duration: 0.104 ms bind test: SELECT user = $1 2023-11-11 05:16:41 UTC:172.31.40.157(42220):postgres@postgres:[8420]:DETAIL: parameters: $1 = 'postgres' 2023-11-11 05:16:41 UTC:172.31.40.157(42220):postgres@postgres:[8420]:LOG: execute test: SELECT user = $1 2023-11-11 05:16:41 UTC:172.31.40.157(42220):postgres@postgres:[8420]:DETAIL: parameters: $1 = 'postgres' 2023-11-11 05:16:41 UTC:172.31.40.157(42220):postgres@postgres:[8420]:LOG: duration: 0.099 ms ...略 2023-11-11 05:16:51 UTC:172.31.40.157(42220):postgres@postgres:[8420]:LOG: duration: 0.071 ms bind test: SELECT user = $1 2023-11-11 05:16:51 UTC:172.31.40.157(42220):postgres@postgres:[8420]:DETAIL: parameters: $1 = 'postgres' 2023-11-11 05:16:51 UTC:172.31.40.157(42220):postgres@postgres:[8420]:LOG: execute test: SELECT user = $1 2023-11-11 05:16:51 UTC:172.31.40.157(42220):postgres@postgres:[8420]:DETAIL: parameters: $1 = 'postgres' 2023-11-11 05:16:51 UTC:172.31.40.157(42220):postgres@postgres:[8420]:LOG: duration: 0.017 ms
今度はparseが1回しか出力されていません。ということは2回目のparseはRDS Proxy側が差し込んだメッセージと考えられそうです。
ここまでの結果から考えるとRDS Proxyの裏側では以下のような処理が動いていると推測されます
※あくまでこれまで分析したログの内容から推測しているだけなので、実際の挙動とは異なる可能性があることをご留意ください。
- 拡張クエリプロトコルによるクエリ発行時に、クライアントが指定したクエリを発行する前に
DEALLOCATE ALLを発行する - クライアントがname付きのクエリを再利用しようとした時、対象のクエリに関するparseのメッセージを差し込む
- クライアントからのメッセージをそのままプロキシすると、対象クエリが既にDEALLOCATEされていて後続処理に失敗するため
- クライアントからparseのメッセージが送信された際に、各接続ごとにnameをキーにしたSQLをキャッシュして再利用に備えていると思われる
まとめ
RDS Proxyのアップデートについてご紹介しました。今回のアップデートによって、これまでピン留めが発生していたワークロードでもピン留めが発生しなくなりRDS Proxyが有効活用できることが期待されます。
ピン留めを回避しようとするとORMが使えなくなるといった課題からRDS & RDS Proxyの利用を諦めていたケースにおいてもアーキテクチャ選定の幅が広がったので、是非抑えておきたいアップデートと言えるでしょう。また、ピン留め対策として低レベルな実装を強いられていたようなケースでもORMを有効活用した高レベルな実装が利用できるようになります。低レベルな実装を利用されている場合は、実装の修正も検討してみてください。
1点注意点として、各種のログから推測する限りnameを指定したクエリのparse結果を再利用することができなさそうなので、その点だけご留意ください。node-postgresのドキュメントに記載されているように、多くのユースケースではこの挙動が問題になるようなことは無いはずです。
Be careful not to fall into the trap of premature optimization. Most of your queries will likely not benefit much, if at all, from using prepared statements. This is a somewhat "power user" feature of PostgreSQL that is best used when you know how to use it - namely with very complex queries with lots of joins and advanced operations like union and switch statements. I rarely use this feature in my own apps unless writing complex aggregate queries for reports and I know the reports are going to be executed very frequently.
https://node-postgres.com/features/queries#prepared-statements
![[AWS 勉強記録] Amazon RDS Proxyとは？](https://images.ctfassets.net/ct0aopd36mqt/wp-thumbnail-2c57fccc8e2c16d5a63f28901f8904ac/7718b1b99dd3a06f49e762d814b6c3c6/amazon-rds)
